Nach meinem Talk auf der jPrime 2019, fragte mich jemand, wie er erkennen könne, wie effektiv die Stringdeduplikation in seiner Anwendung sein würde. Für diese Messung finde ich den Blick auf die Response Rates und den Speicherverbrauch am effektivsten. Denn was hilft es letztlich, wenn wir Speicher gespart haben, aber unsere Performance schlechter ist? Speicher ist billig. Andererseits führt weniger Speicherverbrauch zu einer geringeren Zahl an erreichbaren Objekten und kann uns daher eine höhere Geschwindigkeit bieten.
Nachdem ich mich fragte, wie ich mir die Deduplikationsdaten ansehen könnte, erinnerte ich mich an das Flag -XX:+PrintStringDeduplicationStatistics in Java 8. In Java 9 mit Unified Logging veränderte es sich zu -Xlog:stringdedup*=debug. Jedes Mal, wenn die Deduplikation ausgelöst wird, wird eine Menge nützlicher Informationen ausgeworfen (Listing 1)
Concurrent String Deduplication (90.162s)
Concurrent String Deduplication 72.0B->24.0B(48.0B)
avg 59.8% (90.162s, 90.162s) 0.020ms
Last Exec: 0.020ms, Idle: 16740.738ms, Blocked: 0/0.000ms
Inspected: 3
Skipped: 0( 0.0%)
Hashed: 0( 0.0%)
Known: 0( 0.0%)
New: 3(100.0%) 72.0B
Deduplicated: 2( 66.7%) 48.0B( 66.7%)
Young: 2(100.0%) 48.0B(100.0%)
Old: 0( 0.0%) 0.0B( 0.0%)
Total Exec: 3/1.014ms, Idle: 3/89992.409ms, Blocked: 0/0.000ms
Inspected: 8457
Skipped: 0( 0.0%)
Hashed: 610( 7.2%)
Known: 5640( 66.7%)
New: 2817( 33.3%) 86.7K
Deduplicated: 1810( 64.3%) 51.8K( 59.8%)
Young: 1810(100.0%) 51.8K(100.0%)
Old: 0( 0.0%) 0.0B( 0.0%)
Table
Memory Usage: 187.7K
Size: 4096, Min: 1024, Max: 16777216
Entries: 6644, Load: 162.2%, Cached: 0, Added: 6645, Removed: 1
Resize Count: 2, Shrink Threshold: 2730(66.7%),
Grow Threshold: 8192(200.0%)
Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0
Age Threshold: 3
Queue
Dropped: 0
Jedes Mal, wenn ein Young GC (auch Scavenge oder Partial GC genannt) ausgelöst wird, erhöht sich das Alter unserer Survivors. Wenn sie die Tenuring-Schwelle erreichen, werden sie von den jüngeren zu den älteren Regionen verschoben. Standardmäßig werden Strings dedupliziert, wenn sie das Alter 3 erreichen, also bei ihrem dritten Young GC. Wir wollen das nicht früher tun, denn Deduplikation kostet wertvolle CPU-Zyklen. Wenn der String nicht bis ins hohe Alter überlebt, braucht man auch nicht versuchen, Speicher zu sparen. Falls aus irgendeinem Grund der String vorzeitig zu Old befördert wird, wird er auch früher dedupliziert.
Der DeduplicationExplorer
Um all das auszuprobieren, entwickelte ich meinen DeduplicationExplorer. Er wird euch am meisten nutzen, wenn ihr ihn selbst ausführt. Die Verbindung wird via telnet localhost 8080 hergestellt. Dann können Texte und Befehle an ihn gesendet werden. Der gesamte Text wird in einer ArrayList gespeichert. Das sind die Befehle, die wir unterstützen:
print: zeigt die Strings in der Liste, zusammen mit den Value-Array-Referenzenclear: löscht die Strings aus der Listeygc: erzeugt ein Young GCfgc: erzeugt ein Full GCclose: schließt die Verbindung
In Listing 2 ist der Code für den DeduplicationExplorer zu sehen. Ich empfehle euch, ihn selbst auszuführen.
import java.io.*;
import java.lang.management.*;
import java.lang.reflect.*;
import java.net.*;
import java.util.*;
// Java8:
// -XX:+UseG1GC
// -XX:+UseStringDeduplication
// -XX:+PrintStringDeduplicationStatistics
// -verbose:gc
// Java11:
// -XX:+UseStringDeduplication
// -Xlog:stringdedup*=debug
// -verbose:gc
public class DeduplicationExplorer {
public static void main(String... args) throws IOException {
List<String> lines = new ArrayList<>();
Socket socket = new ServerSocket(8080).accept();
PrintStream out = new PrintStream(
socket.getOutputStream(), true);
out.println("Commands: clear, print, ygc, fgc, close");
BufferedReader in = new BufferedReader(
new InputStreamReader(
socket.getInputStream()));
String line;
while ((line = in.readLine()) != null) {
System.out.println(line);
switch (line) {
case "clear": lines.clear(); break;
case "print": print(lines); break;
case "ygc": youngGC(); break; // young GC
case "fgc": System.gc(); break; // full GC
case "close": return;
default: lines.add(line);
}
}
}
private static void youngGC() {
long collectionCount = YOUNG_GC.getCollectionCount();
do {
// array is too big to be eliminated with escape analysis
byte[] bytes = new byte[1024];
} while (YOUNG_GC.getCollectionCount() == collectionCount);
}
private static void print(List<String> lines) {
System.out.println("lines:");
lines.forEach(DeduplicationExplorer::print);
}
private static void print(String line) {
try {
System.out.printf("\t\"%s\" - %s%n", line, VALUE.get(line));
} catch (IllegalAccessException e) {
throw new IllegalStateException(e);
}
}
private final static Field VALUE;
static {
try {
VALUE = String.class.getDeclaredField("value");
VALUE.setAccessible(true);
} catch (NoSuchFieldException e) {
throw new Error(e);
}
}
private final static GarbageCollectorMXBean YOUNG_GC;
static {
YOUNG_GC = ManagementFactory.getGarbageCollectorMXBeans()
.stream()
.filter(pool -> pool.getName().equals(
"G1 Young Generation"))
.findFirst()
.orElseThrow(() -> new Error("Could not find G1 Young " +
"Generation Garbage Collector MXBean"));
}
}
Beispielsweise öffnete ich das Oracle OpenJDK 12.0.1 mit den folgenden Flags:
-XX:+UseStringDeduplication -Xlog:stringdedup*=debug -verbose:gc
Dann stellte ich die Verbindung mit telnet localhost 8080 her und sendete es:
hello hello hello print
In der Ausgabe des Programms erschien Folgendes:
hello hello hello print lines: "hello" - [B@5d099f62 "hello" - [B@37f8bb67 "hello" - [B@49c2faae
Wie man sieht, hat jeder der drei Strings sein eigenes byte[]. Die Hexadezimalzahl ist der Identity Hash Code, eine zufällige Zahl, die ziemlich einzigartig ist.
Als Nächstes senden wir den Befehl fgc – Full GC. In unserem DeduplicationExplorer sehen wir das GC-Event und die Deduplikationsstatistiken. Wenn wir nun den print-Befehl senden, werden wir sehen, dass alle Strings auf das gleiche byte[] verweisen. Wenn wir die ArrayList durch den clear-Befehl leeren und dann durch fgc ein Full GC ausgeben lassen, wird das geteilte byte[] eingesammelt. Senden wir anschließend „hello“ noch dreimal und rufen wir fgc und print auf, werden wir so etwas erhalten:
fgc
*snip* GC output and deduplication statistics *snip*
print
lines:
"hello" - [B@2e0fa5d3
"hello" - [B@2e0fa5d3
"hello" - [B@2e0fa5d3
Falls der String schon in der JVM als Konstante existierte, wird das die Basis unseres geteilten byte[] sein. Lasst uns zum Beispiel clear eingeben und dann den String main dreimal senden, gefolgt von print. Wir erhalten Folgendes:
clear main main main print lines: "main" - [B@5010be6 "main" - [B@685f4c2e "main" - [B@7daf6ecc
Wenn wir nun fgc und print ausgeben lassen, sehen wir dies hier:
fgc
*snip* GC output and deduplication statistics *snip*
print
lines:
"main" - [B@1f7e245f
"main" - [B@1f7e245f
"main" - [B@1f7e245f
Dieses byte[] ist keines derjenigen, die wir zuvor vom BufferedReader gelesen hatten. Und wenn wir erneut clear eingeben, nochmals main senden und anschließend ein fgc und ein print ausgeben lassen, werden wir wieder das Folgende sehen:
print lines: "main" - [B@1f7e245f
Da wir eine Methode namens main in unserer JVM haben, teilen sich alle Strings dessen byte[].
Young GC
Bislang haben wir uns nur um Full GC gekümmert. Allerdings habe ich auch Unterstützung für das Auslösen eines Young GC durch den Befehl ygc eingebaut. Ich bin ziemlich stolz auf diesen Code, den ich um 5 Uhr morgens im Halbschlaf in Gedanken schrieb, bevor ich wieder einschlief. Für gewöhnlich funktioniert mein im Traum geschriebener Code nicht, aber dieser tut es! Zuerst finde ich den Garbage Collector MXBean für die G1 Young Generation. Dann führe ich die Schleife aus, während die Collection Count gleich ist, und weise 1 kByte Arrays zu. Escape Analysis wird die Heap Allocation nicht entfernen, da die Arrays größer als 64 sind. Mein Traumcode ist in Listing 2 zu sehen.
private static void youngGC() {
long collectionCount = YOUNG_GC.getCollectionCount();
do {
// array is too big to be eliminated with escape analysis
byte[] bytes = new byte[1024];
} while (YOUNG_GC.getCollectionCount() == collectionCount);
}
private final static GarbageCollectorMXBean YOUNG_GC;
static {
YOUNG_GC = ManagementFactory.getGarbageCollectorMXBeans()
.stream()
.filter(pool -> pool.getName().equals(
"G1 Young Generation"))
.findFirst()
.orElseThrow(() -> new Error("Could not find G1 Young " +
"Generation Garbage Collector MXBean"));
}
Nun geben wir die folgenden Befehle ein:
hello hello hello ygc hello ygc hello ygc print
Jedes Mal, wenn wir ygc senden, erscheint ein „Pause Young (Normal)“ in der Konsole. Nach dem dritten ygc sehen wir, dass auch die Deduplikationsstatistik erscheint. Die Ausgabe von print sieht nun so aus:
print lines: "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@37f8bb67 "hello" - [B@49c2faae
Demnach wurden die ersten drei hello-Strings dedupliziert, jedoch nicht die übrigen beiden. Geben wir noch einmal ygc und print ein, wird es zu:
print lines: "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@49c2faae
Und mit dem nächsten ygc gibt print dies aus:
print lines: "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@5d099f62 "hello" - [B@5d099f62
Alles funktioniert so wie es soll.
-XX:+AlwaysTenure
Ein eher seltsames Flag in OpenJDK ist -XX:+AlwaysTenure. Effektiv eliminiert es die Survivor Spaces und befördert alle Survivors von Young zu Old. Obwohl ihr es nicht unbedingt in der Produktion einsetzen solltet, macht das Einschalten in unserem Experiment Spaß. Wir senden nun das Folgende:
hello hello hello ygc print
Wir werden eine ähnliche Ausgabe erhalten wie bei dem Aufruf von System.gc():
hello
hello
hello
ygc
[154.162s][info][gc] GC(0) Pause Young (Normal)
*snip* GC output and deduplication statistics *snip*
print
lines:
"hello" - [B@5d099f62
"hello" - [B@5d099f62
"hello" - [B@5d099f62
Herzliche Grüße aus Kreta
Heinz
